ICTSC2019 二次予選問題解説: MySQLの復旧をお願いします！！

2019.12.10

ICTSC2019 サーバー関連問題解説

問題文

あるデベロッパーから「dev環境と間違えて、prod環境のMySQLで直接truncate table sbtest3;を実行してsbtest3テーブルのデータを削除してしまいました、復旧をお願いします！！」と緊急の連絡を受けました。
このクエリの実行後、すぐに間違いに気づいたデベロッパーはサービスをメンテナンス状態にし、アプリケーションサーバを停止したそうです。

問1(q01)

truncate table sbtest3; というクエリが実行された日時をyymmdd HH:MM:SSのフォーマットで報告してください。
また、どのようにこの日時を特定したかを説明してください。

問2(q02)

truncate tableが実行される直前の状態(truncate tableが実行される1つ前のクエリが実行された状態)にデータを復旧し、復旧後checksum table sysbench.sbtest3;の結果を報告してください。
また、データの復旧に必要な手順を説明してください。

情報

状況

このMySQLは毎日定時にsysbench databaseのバックアップを取得していて(コンテスト問題の作成上truncate table文が実行された日まで)、偶然truncate文が実行される(数分)前にこの日のバックアップが完了していた
バックアップは以下のコマンドで取得されている
mysqldump --opt --single-transaction --master-data=2 --default-character-set=utf8mb4 --databases sysbench > /root/backup/backup.dump
mysql -u root -p < /root/backup/backup.dumpでバックアップが取得された時点に復旧できる
adminユーザからsudo suすることでrootユーザから操作してください

問題サーバー

IPアドレス: 192.168.0.1
ユーザー: admin
パスワード: USerPw@19
DBユーザー: root
DBパスワード: root

ゴール

問1, truncate table sbtest3; というクエリが実行された日時を特定し、その特定方法を説明していること
問2, MySQLのデータが復旧し、その手順の説明とchecksum table sysbench.sbtest3;の結果が報告されていること
問1に正解すると部分点が与えられます。

問題解説

「本番環境で間違ってtruncate table ...を実行してしまったから、その直前の状態までデータ復旧してほしい！！」
というデータベースの復旧問題でした。

あまり想像して楽しくなる状況ではありませんが、ソフトウェア開発をする上でデータベースのデータの復旧方法を知っておいても損はないと思います。
そこで、MySQLを例にバックアップと更新ログを利用して任意のタイミングまでデータを復旧する問題を出題しました。
DBMSごとの際はありますが、基本的にデータベースの復旧方法(特にロールフォーワードリカバリ)の概念は同じですので、今後使うDBMSでこういった状況に対応できるかを考えてみてください。

具体的な解法を説明する前にMySQLにおけるリカバリ方法、バイナリログ、バックアップについて説明します。

ポイント・イン・タイム・リカバリ (PITR)

データベースのバックアップを定期的に取得するだけでは、その時点のデータを復元することしかできないため、バックアップ以降の更新データを失うことになります。
そこで、データの永続化を保証する多くのデータベースでは、バックアップとは別にデータの更新情報を保持しておき、バックアップとそれ以降のデータ更新を復元することで任意の時点のデータをリカバリできるようにしています。このようなリカバリ方法をポイントインタイムリカバリ(PITR)と言います。

バックアップ以降のデータ更新情報をどのように保持するかはDBMSによって異なりますが、MySQLでは後述するバイナリログを利用することで取得できます。

バイナリログ

バイナリログにはMySQL serverで実行された更新がイベントという形で出力されています。
イベントには直接実行されたクエリが出力されているわけではなく、行ごとの変更分が特定のフォーマットにしたがって出力されています。
この他にもバイナリログそのもののバージョンやサーバの設定などのメタ情報も含まれており、これを利用してリカバリやレプリケーションを行うことができます。
truncate table ...を含むDDLはSTATEMENTが直接書かれていたり、推奨されませんが、DMLを直接STATEMENTに出力したりも出来ます。詳しくはバイナリログのドキュメントを参照してください

バイナリログの中身はmysqlbinlogコマンドを使うことで確認でき、より詳細に確認したい場合は--base64-output=DECODE-ROWS -vvなどのオプションをつけることで、実際に実行されたSQL文とは異なりますが、SQL文として復元されたものを確認できます。ただしクエリはコメントアウトされているので、このオプションをつけた結果をリカバリに使うことは出来ません。

バイナリログから特定の期間の更新を取得するには時間で指定する方法とバイナリログ中のオフセットを利用する方法がありますが、時間単位での指定は秒単位でしかできないため、リカバリにはオフセットを用いて指定する --start-position,--stop-positionを利用することをおすすめします。(秒間1クエリしか実行していない、なんてサービスはほとんどないはず)

バックアップ

MySQLにおけるバックアップ方法はいくつもあり実際は要件に合わせて選択しますが、今回はMySQL標準の論理バックアップクライアントのmysqldumpを利用してバックアップしました。
オプションの説明は省略しますが、問題環境では以下のコマンドでsysbench databaseの完全バックアップが取得されていました。

mysqldump --opt --single-transaction --master-data=2 --default-character-set=utf8mb4 --databases sysbench > /root/backup/backup.dump

--master-data=2が指定されていることから、バックアップを行ったホストに対してレプリケーションを繋ぐ際のコマンド(CHANGE MASTER...)がコメントアウトされて出力されます。この出力を見ることで、バックアップ以降の更新がバイナリログのどこから始まっているかをバイナリログのオフセットとして確認できます。

復旧手順

それでは実際に今回の問題環境でPITRを実施してデータを復旧する方法を説明します。

PITRの項で説明したように、まずはバックアップをリストアし、バックアップ以降でtruncate table sbtest3;の実行直前までの更新をバイナリログから抽出して適用することで復旧します。

mysqldumpによるダンプファイルの22行目に以下の出力があることからバックアップ以降の更新はbinlog.000018の34626719byte目以降ということがわかります。

-- CHANGE MASTER TO MASTER_LOG_FILE='binlog.000018', MASTER_LOG_POS=34626719;

次に、バイナリログからmysqlbinlogコマンドを使ってtruncate table...を実行を表すイベントのオフセットを取得します。
問題環境ではデータの更新が記録されているのはbinlog.000018だけなので、このファイルについてだけ考えれば良いです。

$ mysqlbinlog --no-defaults --base64-output=DECODE-ROWS -vv --start-position=34626719  binlog.000018 | grep -B 10 truncate
/*!80001 SET @@session.original_commit_timestamp=1574235055802260*//*!*/;
/*!80014 SET @@session.original_server_version=80018*//*!*/;
/*!80014 SET @@session.immediate_server_version=80018*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 54452036
#191120 16:30:55 server id 1  end_log_pos 54452141 CRC32 0x7e67e1d2     Query   thread_id=11    exec_time=0 error_code=0    Xid = 189179
use `sysbench`/*!*/;
SET TIMESTAMP=1574235055/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=255,@@session.collation_connection=255,@@session.collation_server=255/*!*/;
truncate table sbtest3

この出力の# at {数字}を見ることでtruncate文を実行したのが54452036 byte目から始まるイベントとわかります。
また、次の行をみると191120 16:30:55に実行されたことがわかります (問1)

問1としてあえて秒単位でしかない実行時刻を解答してもらったのは、実際にこういった問題が起こった場合には似たようなクエリがアプリケーションの正常な処理として実行されていたり、実は何回も間違った後だったりするため確認作業を必要とすることが多いからです。
辛いですね。。。

ここまででわかったbinlogの状況を図1に整理してみます。

スクリーンショット 2019-12-08 15.10.27.png.webp — 図1 binlogの状況

バックアップを適用することで②の直前の状態にまでデータが復旧されるため、②から③までの更新情報を適用する必要があります。
①から②の部分も適用したチームも見られましたが、この部分の更新分はバックアップに含まれているので、重複した更新を適用してしまうことになります。

最後にここまでで取得したオフセットを--start-positionと--stop-positionで指定して抽出し、適用することでリカバリが完了します(問2)

mysqlbinlog --no-defaults --start-position=34626719 --stop-position=54452036 binlog.000018 | mysql -u root -p
# または
mysqlbinlog --no-defaults --start-position=34626719 --stop-position=54452036 binlog.000018 > recover.sql
mysql -u root -p < recover.sql

採点基準

問1: 30%
問2: 70%

問2の採点にはリカバリ後に実行してもらったchecksum table ...の結果を利用するつもりでしたが、問題環境ではバイナリログからの抽出位置を正しく指定しなくてもchecksumが同じ値になってしまうことがありました。
そのため解答中のリカバリ方法の説明で、バックアップ以降、truncate table文まで(図1の②~③部分)の更新分を抽出、適用していることを確認して正解としました。

ICTSC2019 二次予選 問題解説: MySQLの復旧をお願いします！！

問題文